perf: add a ShellGlobal property to call glFinish and log the time

It's useful to know how long frames are taking to render on the GPU.
This is impossible to measure in the normal case because frames may
parallelize with previous frames, but by calling glFinish() at the
end of the frame, we can create a (somewhat artificial, but useful)
environment where we have a meaningful timestamp for the frame
finishing drawing.

https://bugzilla.gnome.org/show_bug.cgi?id=732350

diff --git a/src/shell-global.c b/src/shell-global.c
index 571483e8128cf8a5817c40d81ddfa76ee46f1a33..bf38e7d9803b36e69abd29398301f1415620bf3b 100644 (file)
--- a/src/shell-global.c
+++ b/src/shell-global.c
@@ -97,6 +97,7 @@ struct _ShellGlobal {
 
   gboolean has_modal;
   gboolean frame_timestamps;
+  gboolean frame_finish_timestamp;
 };
 
 enum {
@@ -118,6 +119,7 @@ enum {
   PROP_USERDATADIR,
   PROP_FOCUS_MANAGER,
   PROP_FRAME_TIMESTAMPS,
+  PROP_FRAME_FINISH_TIMESTAMP,
 };
 
 /* Signals */
@@ -151,6 +153,9 @@ shell_global_set_property(GObject         *object,
     case PROP_FRAME_TIMESTAMPS:
       global->frame_timestamps = g_value_get_boolean (value);
       break;
+    case PROP_FRAME_FINISH_TIMESTAMP:
+      global->frame_finish_timestamp = g_value_get_boolean (value);
+      break;
     default:
       G_OBJECT_WARN_INVALID_PROPERTY_ID (object, prop_id, pspec);
       break;
@@ -225,6 +230,9 @@ shell_global_get_property(GObject         *object,
     case PROP_FRAME_TIMESTAMPS:
       g_value_set_boolean (value, global->frame_timestamps);
       break;
+    case PROP_FRAME_FINISH_TIMESTAMP:
+      g_value_set_boolean (value, global->frame_finish_timestamp);
+      break;
     default:
       G_OBJECT_WARN_INVALID_PROPERTY_ID (object, prop_id, pspec);
       break;
@@ -515,6 +523,13 @@ shell_global_class_init (ShellGlobalClass *klass)
                                                          "Whether to log frame timestamps in the performance log",
                                                          FALSE,
                                                          G_PARAM_READWRITE));
+  g_object_class_install_property (gobject_class,
+                                   PROP_FRAME_FINISH_TIMESTAMP,
+                                   g_param_spec_boolean ("frame-finish-timestamp",
+                                                         "Frame Finish Timestamps",
+                                                         "Whether at the end of a frame to call glFinish and log paintCompletedTimestamp",
+                                                         FALSE,
+                                                         G_PARAM_READWRITE));
 }
 
 /*
@@ -781,8 +796,56 @@ global_stage_before_paint (gpointer data)
 }
 
 static gboolean
-global_stage_after_paint (gpointer data)
+load_gl_symbol (const char  *name,
+                void       **func)
+{
+  *func = cogl_get_proc_address (name);
+  if (!*func)
+    {
+      g_warning ("failed to resolve required GL symbol \"%s\"\n", name);
+      return FALSE;
+    }
+  return TRUE;
+}
+
+static void
+global_stage_after_paint (ClutterStage *stage,
+                          ShellGlobal  *global)
 {
+  /* At this point, we've finished all layout and painting, but haven't
+   * actually flushed or swapped */
+
+  if (global->frame_timestamps && global->frame_finish_timestamp)
+    {
+      /* It's interesting to find out when the paint actually finishes
+       * on the GPU. We could wait for this asynchronously with
+       * ARB_timer_query (see https://bugzilla.gnome.org/show_bug.cgi?id=732350
+       * for an implementation of this), but what we actually would
+       * find out then is the latency for drawing a frame, not how much
+       * GPU work was needed, since frames can overlap. Calling glFinish()
+       * is a fairly reliable way to separate out adjacent frames
+       * and measure the amount of GPU work. This is turned on with a
+       * separate property from ::frame-timestamps, since it should not
+       * be turned on if we're trying to actual measure latency or frame
+       * rate.
+       */
+      static void (*finish) (void);
+
+      if (!finish)
+        load_gl_symbol ("glFinish", (void **)&finish);
+
+      finish ();
+
+      shell_perf_log_event (shell_perf_log_get_default (),
+                            "clutter.paintCompletedTimestamp");
+    }
+}
+
+static gboolean
+global_stage_after_swap (gpointer data)
+{
+  /* Everything is done, we're ready for a new frame */
+
   ShellGlobal *global = SHELL_GLOBAL (data);
 
   if (global->frame_timestamps)
@@ -974,17 +1037,24 @@ _shell_global_set_plugin (ShellGlobal *global,
                                          global_stage_before_paint,
                                          global, NULL);
 
+  g_signal_connect (global->stage, "after-paint",
+                    G_CALLBACK (global_stage_after_paint), global);
+
   clutter_threads_add_repaint_func_full (CLUTTER_REPAINT_FLAGS_POST_PAINT,
-                                         global_stage_after_paint,
+                                         global_stage_after_swap,
                                          global, NULL);
 
   shell_perf_log_define_event (shell_perf_log_get_default(),
                                "clutter.stagePaintStart",
                                "Start of stage page repaint",
                                "");
+  shell_perf_log_define_event (shell_perf_log_get_default(),
+                               "clutter.paintCompletedTimestamp",
+                               "Paint completion on GPU",
+                               "");
   shell_perf_log_define_event (shell_perf_log_get_default(),
                                "clutter.stagePaintDone",
-                               "End of stage page repaint",
+                               "End of frame, possibly including swap time",
                                "");
 
   g_signal_connect (global->stage, "notify::key-focus",